Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Crystal::Tracing for runtime tracing #14659

Merged
merged 19 commits into from
Jun 15, 2024

Conversation

ysbaddaden
Copy link
Contributor

@ysbaddaden ysbaddaden commented Jun 3, 2024

Implements tracing of the garbage collector and the scheduler as per #14618

Tracing is enabled by compiling with -Dtracing then individual tracing must be enabled at runtime with the CRYSTAL_TRACE environment variable that is a comma separated list of sections to enable, for example:

  • none to disable everything (by default)
  • gc
  • sched
  • gc,sched
  • all to enable everything

The traces are printed to the standard error by default, but this can be changed at runtime with the CRYSTAL_TRACE_FILE environment variable. For example trace.log. You can also redirect the standard error to a file (e.g. 2> trace.log on UNIX shell).

Technical note: tracing happens before the stdlib is initialized, so the implementation must rely on some LibC methods directly (i.e. read environment variable, write to file descriptor) and can't use the core/stdlib abstractions.

Note: the Thread#current_thread? commit could be extracted into a distinct PR. Done: #14660

This was referenced Jun 3, 2024
@ysbaddaden ysbaddaden linked an issue Jun 3, 2024 that may be closed by this pull request
@straight-shoota
Copy link
Member

the Thread#current_thread? commit could be extracted into a distinct PR.

Then let's do that, please 🙏

Copy link
Member

@straight-shoota straight-shoota left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

polish: Standardize format for calls to Crystal.trace.
The section argument is always a symbol, the operation argument sometimes a symbol, sometimes a string.

Crystal.trace :sched, :spawn
Crystal.trace :sched, "event_loop"

It would be nice using the same format, maybe the operation could always be a string?

src/crystal/system/print_error.cr Outdated Show resolved Hide resolved
src/crystal/tracing.cr Outdated Show resolved Hide resolved
src/crystal/tracing.cr Outdated Show resolved Hide resolved
@ysbaddaden ysbaddaden self-assigned this Jun 7, 2024
@ysbaddaden
Copy link
Contributor Author

@straight-shoota following your review, I made the following changes:

  1. I replaced the Crystal.trace macro with a couple def methods (one that yield and one that don't), which led to:
  • the operation arg is now always a String 👍
  • the method still yields twice, but this is no longer injecting the code twice, so it should be fine?
  1. I replaced the LibC.WideCharToMultiByte call with a pure Crystal alternative that leverages String.each_utf16_char(slice, &) and loops to avoid a buffer overflow and splitting a multibyte char across multiple prints.

src/crystal/system/print_error.cr Outdated Show resolved Hide resolved
src/crystal/system/print_error.cr Outdated Show resolved Hide resolved
src/crystal/tracing.cr Outdated Show resolved Hide resolved
src/crystal/tracing.cr Outdated Show resolved Hide resolved
Fixes a bug where it'd print the whole buffer despite not necessarily
using it fully (when last char doesn't fit).

Also no longer restricts the method to Windows; it might be useful in
other cases?
@ysbaddaden
Copy link
Contributor Author

Thanks @straight-shoota. I applied all your suggestions!

@straight-shoota straight-shoota added this to the 1.13.0 milestone Jun 13, 2024
src/crystal/tracing.cr Outdated Show resolved Hide resolved
@ysbaddaden
Copy link
Contributor Author

ysbaddaden commented Jun 13, 2024

I noticed that one macro used constant.downcase while the other used lowerscore in a completely different place, so I grouped the logic into the Tracing::Section enum as a couple methods: .from_id(slice) and #to_id (instead of #id) and now both are using lowerscore.

@straight-shoota straight-shoota changed the title Feature: runtime tracing Add Crystal::Tracing for runtime tracing Jun 15, 2024
@straight-shoota straight-shoota merged commit ff01499 into crystal-lang:master Jun 15, 2024
61 checks passed
@ysbaddaden ysbaddaden deleted the feature/tracing branch June 17, 2024 09:15
@crysbot
Copy link

crysbot commented Sep 19, 2024

This pull request has been mentioned on Crystal Forum. There might be relevant details there:

https://forum.crystal-lang.org/t/want-to-hear-a-feedback-on-debugging-support/7190/3

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

RFC: Tracing
4 participants